From 4f12a2b5a7a933b23012aac18edaf760f885b064 Mon Sep 17 00:00:00 2001 From: Alex Crichton Date: Thu, 31 Jul 2014 12:53:17 -0700 Subject: [PATCH] Add a small profiling framework This should help aid in debugging slow parts of cargo by setting the CARGO_PROFILE environment variable. --- src/cargo/core/registry.rs | 4 +- src/cargo/core/source.rs | 7 ++- src/cargo/lib.rs | 1 + src/cargo/ops/cargo_compile.rs | 3 ++ src/cargo/ops/cargo_rustc/context.rs | 4 +- src/cargo/ops/cargo_rustc/fingerprint.rs | 3 +- src/cargo/ops/cargo_rustc/job_queue.rs | 4 +- src/cargo/ops/cargo_rustc/mod.rs | 3 +- src/cargo/util/mod.rs | 1 + src/cargo/util/profile.rs | 62 ++++++++++++++++++++++++ 10 files changed, 85 insertions(+), 7 deletions(-) create mode 100644 src/cargo/util/profile.rs diff --git a/src/cargo/core/registry.rs b/src/cargo/core/registry.rs index d737d429f..789bf1490 100644 --- a/src/cargo/core/registry.rs +++ b/src/cargo/core/registry.rs @@ -1,5 +1,5 @@ use core::{Source, SourceId, SourceMap, Summary, Dependency, PackageId, Package}; -use util::{CargoResult, ChainError, Config, human}; +use util::{CargoResult, ChainError, Config, human, profile}; pub trait Registry { fn query(&mut self, name: &Dependency) -> CargoResult>; @@ -83,7 +83,9 @@ impl<'a> PackageRegistry<'a> { let mut source = source_id.load(self.config); // Ensure the source has fetched all necessary remote data. + let p = profile::start(format!("updating: {}", source_id)); try!(source.update()); + drop(p); if override { self.overrides.push(source_id.clone()); diff --git a/src/cargo/core/source.rs b/src/cargo/core/source.rs index 9091a0ef9..c186a628f 100644 --- a/src/cargo/core/source.rs +++ b/src/cargo/core/source.rs @@ -158,8 +158,11 @@ impl Show for SourceId { try!(write!(f, "?ref={}", reference)); } - if precise.is_some() { - try!(write!(f, "#{}", precise.get_ref())); + match *precise { + Some(ref s) => { + try!(write!(f, "#{}", s.as_slice().slice_to(8))); + } + None => {} } }, SourceId { kind: RegistryKind, .. } => { diff --git a/src/cargo/lib.rs b/src/cargo/lib.rs index ae8aeb22b..f80f38d2e 100644 --- a/src/cargo/lib.rs +++ b/src/cargo/lib.rs @@ -11,6 +11,7 @@ extern crate regex; extern crate semver; extern crate serialize; extern crate term; +extern crate time; extern crate url; #[phase(plugin)] extern crate regex_macros; #[phase(plugin, link)] extern crate log; diff --git a/src/cargo/ops/cargo_compile.rs b/src/cargo/ops/cargo_compile.rs index 96182344b..43a0214ff 100644 --- a/src/cargo/ops/cargo_compile.rs +++ b/src/cargo/ops/cargo_compile.rs @@ -34,6 +34,7 @@ use ops; use sources::{PathSource}; use util::config::{Config, ConfigValue}; use util::{CargoResult, Wrap, config, internal, human, ChainError, toml}; +use util::profile; pub struct CompileOptions<'a> { pub update: bool, @@ -67,6 +68,7 @@ pub fn compile(manifest_path: &Path, manifest_path.dir_path())); let (packages, resolve, resolve_with_overrides, sources) = { + let _p = profile::start("resolving..."); let lockfile = manifest_path.dir_path().join("Cargo.lock"); let source_id = package.get_package_id().get_source_id(); @@ -117,6 +119,7 @@ pub fn compile(manifest_path: &Path, }).collect::>(); { + let _p = profile::start("compiling"); let mut config = try!(Config::new(*shell, update, jobs, target)); try!(scrape_target_config(&mut config, &user_configs)); diff --git a/src/cargo/ops/cargo_rustc/context.rs b/src/cargo/ops/cargo_rustc/context.rs index ad078865b..6e65574ac 100644 --- a/src/cargo/ops/cargo_rustc/context.rs +++ b/src/cargo/ops/cargo_rustc/context.rs @@ -3,7 +3,7 @@ use std::str; use core::{SourceMap, Package, PackageId, PackageSet, Resolve, Target}; use util; -use util::{CargoResult, ChainError, internal, Config}; +use util::{CargoResult, ChainError, internal, Config, profile}; use super::layout::{Layout, LayoutProxy}; @@ -100,6 +100,8 @@ impl<'a, 'b> Context<'a, 'b> { /// Prepare this context, ensuring that all filesystem directories are in /// place. pub fn prepare(&mut self, pkg: &'a Package) -> CargoResult<()> { + let _p = profile::start("preparing layout"); + try!(self.host.prepare().chain_error(|| { internal(format!("couldn't prepare build directories for `{}`", pkg.get_name())) diff --git a/src/cargo/ops/cargo_rustc/fingerprint.rs b/src/cargo/ops/cargo_rustc/fingerprint.rs index 3db58b3e1..3b4fd04dd 100644 --- a/src/cargo/ops/cargo_rustc/fingerprint.rs +++ b/src/cargo/ops/cargo_rustc/fingerprint.rs @@ -5,7 +5,7 @@ use std::io::{fs, File}; use core::{Package, Target}; use util; use util::hex::short_hash; -use util::{CargoResult, Fresh, Dirty, Freshness, internal, Require}; +use util::{CargoResult, Fresh, Dirty, Freshness, internal, Require, profile}; use super::job::Job; use super::context::Context; @@ -24,6 +24,7 @@ use super::context::Context; pub fn prepare<'a, 'b>(cx: &mut Context<'a, 'b>, pkg: &'a Package, targets: &[&'a Target]) -> CargoResult<(Freshness, Job, Job)> { + let _p = profile::start(format!("fingerprint: {}", pkg)); let filename = format!(".{}.{}.fingerprint", pkg.get_name(), short_hash(pkg.get_package_id())); let filename = filename.as_slice(); diff --git a/src/cargo/ops/cargo_rustc/job_queue.rs b/src/cargo/ops/cargo_rustc/job_queue.rs index a52a23913..4eb5a516e 100644 --- a/src/cargo/ops/cargo_rustc/job_queue.rs +++ b/src/cargo/ops/cargo_rustc/job_queue.rs @@ -4,7 +4,7 @@ use term::color::YELLOW; use core::{Package, PackageId, Resolve}; use util::{Config, TaskPool, DependencyQueue, Fresh, Dirty, Freshness}; -use util::CargoResult; +use util::{CargoResult, profile}; use super::job::Job; @@ -51,6 +51,8 @@ impl<'a, 'b> JobQueue<'a, 'b> { /// necessary dependencies, in order. Freshness is propagated as far as /// possible along each dependency chain. pub fn execute(&mut self) -> CargoResult<()> { + let _p = profile::start("executing the job graph"); + // Iteratively execute the dependency graph. Each turn of this loop will // schedule as much work as possible and then wait for one job to finish, // possibly scheduling more work afterwards. diff --git a/src/cargo/ops/cargo_rustc/mod.rs b/src/cargo/ops/cargo_rustc/mod.rs index 1b94648d8..1f5d68909 100644 --- a/src/cargo/ops/cargo_rustc/mod.rs +++ b/src/cargo/ops/cargo_rustc/mod.rs @@ -7,7 +7,7 @@ use semver::Version; use core::{SourceMap, Package, PackageId, PackageSet, Target, Resolve}; use util; use util::{CargoResult, ProcessBuilder, CargoError, human, caused_human}; -use util::{Config, Freshness, internal, ChainError}; +use util::{Config, Freshness, internal, ChainError, profile}; use self::job::Job; use self::job_queue::JobQueue; @@ -87,6 +87,7 @@ fn compile<'a, 'b>(targets: &[&'a Target], pkg: &'a Package, jobs: &mut Vec<(&'a Package, Freshness, (Job, Job))>) -> CargoResult<()> { debug!("compile_pkg; pkg={}; targets={}", pkg, targets); + let _p = profile::start(format!("preparing: {}", pkg)); if targets.is_empty() { return Ok(()) diff --git a/src/cargo/util/mod.rs b/src/cargo/util/mod.rs index 7d567e68e..f1da499f4 100644 --- a/src/cargo/util/mod.rs +++ b/src/cargo/util/mod.rs @@ -20,6 +20,7 @@ pub mod toml; pub mod paths; pub mod errors; pub mod hex; +pub mod profile; mod pool; mod dependency_queue; mod to_url; diff --git a/src/cargo/util/profile.rs b/src/cargo/util/profile.rs new file mode 100644 index 000000000..11e43e1f5 --- /dev/null +++ b/src/cargo/util/profile.rs @@ -0,0 +1,62 @@ +use std::os; +use std::mem; +use std::fmt::Show; +use time; + +local_data_key!(profile_stack: Vec) +local_data_key!(messages: Vec) + +type Message = (uint, u64, String); + +pub struct Profiler { + desc: String, +} + +fn enabled() -> bool { os::getenv("CARGO_PROFILE").is_some() } + +pub fn start(desc: T) -> Profiler { + if !enabled() { return Profiler { desc: String::new() } } + + let mut stack = profile_stack.replace(None).unwrap_or(Vec::new()); + stack.push(time::precise_time_ns()); + profile_stack.replace(Some(stack)); + + Profiler { + desc: desc.to_string(), + } +} + +impl Drop for Profiler { + fn drop(&mut self) { + if !enabled() { return } + + let mut stack = profile_stack.replace(None).unwrap_or(Vec::new()); + let mut msgs = messages.replace(None).unwrap_or(Vec::new()); + + let start = stack.pop().unwrap(); + let end = time::precise_time_ns(); + + let msg = mem::replace(&mut self.desc, String::new()); + if stack.len() == 0 { + fn print(lvl: uint, msgs: &[Message]) { + let mut last = 0; + for (i, &(l, time, ref msg)) in msgs.iter().enumerate() { + if l != lvl { continue } + println!("{} {:6}ms - {}", " ".repeat(lvl + 1), + time / 1000000, msg); + + print(lvl + 1, msgs.slice(last, i)); + last = i; + } + + } + msgs.push((0, end - start, msg)); + print(0, msgs.as_slice()); + } else { + msgs.push((stack.len(), end - start, msg)); + } + profile_stack.replace(Some(stack)); + messages.replace(Some(msgs)); + + } +} -- 2.30.2